Implement file logging with default xunit tests #798

JunTaoLuo · 2018-04-09T17:29:37Z

This is needed for aspnet/KestrelHttpServer#2390:

The usage is:

Extend base class of LoggedTest

    public class MyTests : LoggedTest
    {
    }

Use the properties of the base class LoggedTest

        [Fact]
        public void MyTest()
        {
            // using LoggerFactory
            using (var webhost = WebHost.CreateDefaultBuilder().ConfigureServices(AddTestLogging).Build())
            {
                //...
            }
            // using Logger
            Logger.LogInformation("Hello world");
            // using TestOutputHelper
           new XunitLogger(TestOutpuHelper, nameof(MyClass), LogLevel.Information);
            // using TestSink
            TestSink.Writes.ForEach(c => Assert.True(c.LogLevel >= LogLeve.Debug));
        }

The verbosity can be controlled via the LogLevelAttribute:

        [Fact]
        [LogLevel(LogLevel.Information)]
        public void MyTest()
        {
            // This will noop
            Logger.Debug("Hello world");
        }

JunTaoLuo · 2018-04-09T17:30:42Z

src/Microsoft.Extensions.Logging.Testing/Xunit/Shared/SkippedTestCase.cs

+using Xunit.Abstractions;
+using Xunit.Sdk;
+
+namespace Microsoft.AspNetCore.Testing.xunit


Going to make this type public from testing instead of duplicating here.

aspnet/Testing#301

JunTaoLuo · 2018-04-09T17:31:47Z

test/Microsoft.Extensions.Logging.Testing.Tests/LoggedTestXunitTests.cs

+        {
+            Assert.NotNull(LoggerFactory);
+            LoggerFactory.CreateLogger(nameof(AssemblyTestLogTests)).LogInformation("Hello world");
+            LoggerFactory.CreateLogger(nameof(AssemblyTestLogTests)).LogDebug("Debug Hello world");


TODO: add more tests

JunTaoLuo · 2018-04-09T17:32:52Z

src/Microsoft.Extensions.Logging.Testing/Microsoft.Extensions.Logging.Testing.csproj

  <PropertyGroup>
    <Description>Helpers for writing tests that use Microsoft.Extensions.Logging. Contains null implementations of the abstractions that do nothing, as well as test implementations that are observable.</Description>
-    <TargetFramework>netstandard2.0</TargetFramework>
+    <TargetFrameworks>netstandard2.0;net461</TargetFrameworks>


I needed to cross-target to enable test discovery on full framework.

pakrym · 2018-04-09T18:28:18Z

src/Microsoft.Extensions.Logging.Testing/AssemblyTestLog.cs

+                '\\', // back slash
+                '/', // forward slash
+                '\x7F', // delete
+            });


pakrym · 2018-04-09T18:29:31Z

src/Microsoft.Extensions.Logging.Testing/AssemblyTestLog.cs

+            {
+                if (InvalidFileChars.Contains(c))
+                {
+                    var escapedChar = Convert.ToByte(c).ToString("x");


This expands string size a lot, maybe just do '_' ?

I did do that at one point but it made test names highly unreadable. Also converting to the same character for all invalid chars creates lots of collisions. With the test name shortening logic in place, I don't think this should be an issue.

Hmm right now I expand illegal characters like / => -x2f, maybe I can reduce the verbosity and just leave it as 2f which is a bit harder to parse out but still retains most of the information.

I did do that at one point but it made test names highly unreadable

Hex is not very readable too.

With the test name shortening logic in place, I don't think this should be an issue.

Replacing a bunch of '_' with one would be a nice addition to shortening logic.

Poor choice of words, I meant file name collisions instead of readability. Even though we have collision resolution, I would prefer retaining as much information as possible of the original arguments used by default. I've shortened the escaping to just the hex.

Do you really prefer Testing_https:-x2f-x2flocalhost over Testing_https:_localhost ? To me, the second one is much easier to figure out.

For that case maybe, but this will create many collisions for kestrel tests, for example: https://github.com/aspnet/KestrelHttpServer/blob/dev/test/shared/HttpParsingData.cs#L192. Also I don't like coalescing multiple _ since that makes tests like https://github.com/aspnet/KestrelHttpServer/blob/dev/test/shared/HttpParsingData.cs#L254-L255 indistiguishable.

@halter73 what would you prefer?

pakrym · 2018-04-09T18:33:56Z

src/Microsoft.Extensions.Logging.Testing/Xunit/LoggedTestCaseRunner.cs

+{
+    public class LoggedTestCaseRunner : XunitTestCaseRunner
+    {
+        public LoggedTestCaseRunner(IXunitTestCase testCase, string displayName, string skipReason, object[] constructorArguments, object[] testMethodArguments, IMessageBus messageBus, ExceptionAggregator aggregator, CancellationTokenSource cancellationTokenSource) : base(testCase, displayName, skipReason, constructorArguments, testMethodArguments, messageBus, aggregator, cancellationTokenSource)


Linebreaks? This line spans 2 monitors

pakrym · 2018-04-09T18:36:47Z

src/Microsoft.Extensions.Logging.Testing/Xunit/LoggedTestInvoker.cs

+        {
+            var testClass = base.CreateTestClass();
+
+            if (testClass is LoggedTest loggedTestClass)


Can't we do it for any class, so you're not forced to inherit and can just inject the constructor argument?

We are not injecting it as a constructor argument. We are setting the property of the base class LoggedTest.

Unless you are suggesting we change the design?

I always thought we are going argument injection, that's why we started with argument injection DI prototype.

Found a way of removing the need to flow the ITestOutputHelper with constructors.

pakrym · 2018-04-09T18:38:16Z

test/Microsoft.Extensions.Logging.Testing.Tests/LoggedTestXunitTests.cs

+{
+    public class LoggedTestXunitTests : LoggedTest
+    {
+        public LoggedTestXunitTests(ITestOutputHelper output) : base(output)


Do we still have to pass ITestOutputHelper around? Can ILoggerFactory be injected directly?

We don't need to pass it around since we resolve the ITestOutputHelper from the list of constructor args. Though I think removing it would be a breaking change so we'll need to update all the places currently using LoggedTest.

Actually I don't think we can remove ITestOutputHelper. What if the user wants to initialize a different LoggerFactory by calling StartLog (to override test name for example)? That call needs the ITestOutputHelper.

JunTaoLuo · 2018-04-09T18:38:17Z

Note: WIP adding and fixing tests.

analogrelay · 2018-04-09T18:33:55Z

src/Microsoft.Extensions.Logging.Testing/Xunit/LoggedTestFrameworkDiscoverer.cs

+{
+    public class LoggedTestFrameworkDiscoverer : XunitTestFrameworkDiscoverer
+    {
+        private List<(Type Type, IXunitTestCaseDiscoverer Discoverer)> Discoverers { get; }


Dictionary?

Ah yes, at one point, I was using a best match on the type which needed a list of discoverers for types from the most specific to the most general. Now that I'm using an exact match on the type and falling back to non-logged discoverers, this can totally be just a dictionary.

analogrelay · 2018-04-09T18:55:30Z

src/Microsoft.Extensions.Logging.Testing/Xunit/LoggedTestInvoker.cs

+            if (testClass is LoggedTest loggedTestClass)
+            {
+                var classType = loggedTestClass.GetType();
+                var testOutputHelper = ConstructorArguments.Single(a => typeof(ITestOutputHelper).IsAssignableFrom(a.GetType())) as ITestOutputHelper;


In theory we could get the ITestOutputHelper from the source (whatever that is) rather than extracting it from constructor arguments.

analogrelay · 2018-04-09T18:56:04Z

src/Microsoft.Extensions.Logging.Testing/Xunit/LoggedTestInvoker.cs

+                var classType = loggedTestClass.GetType();
+                var testOutputHelper = ConstructorArguments.Single(a => typeof(ITestOutputHelper).IsAssignableFrom(a.GetType())) as ITestOutputHelper;
+                var logLevelAttribute = TestMethod.GetCustomAttribute(typeof(LogLevelAttribute)) as LogLevelAttribute;
+                var testName = TestMethodArguments.Aggregate(TestMethod.Name, (a, b) => $"{a}_{(b ?? "null")}");


string.Join('_', ...)?

Closest I can come up with is string.Join("_", TestMethod.Name, TestMethodArguments) but that won't be able to mark null object with "null" string

From adding tests previously, I remember it being useful to distinguish between null strings and empty strings for example. That's why I special cased null here.

👍 for foldl

What is foldl?

The hipster name for Aggregate.

pakrym · 2018-04-09T18:58:42Z

Supporting https://github.com/aspnet/Logging/blob/dev/src/Microsoft.Extensions.Logging.Testing/ITestSink.cs would be interesting too, would make some kestrel tests even simpler

analogrelay · 2018-04-09T19:17:48Z

Ooh, yeah, automatically register a TestLogger and TestSink. I like that. If it's simple, do it, if it's more than a couple minutes work, file a bug and let's get this in.

halter73 · 2018-04-09T22:15:21Z

src/Microsoft.Extensions.Logging.Testing/AssemblyTestLog.cs

+            .Union(new char[] {
+                ' ', // space
+                '\\', // back slash
+                '/', // forward slash


Isn't this already an InvalidFileNameChar on every platform? Maybe a whitelist would be better.

I think so but no harm in duplicates. I prefer not using a whitelist since that probably takes more work to construct.

There's way less that could go wrong with a whitelist and a lot less to think about. How do you justify replacing the delete character but not the other control characters?

I think it would take much effort to only allow alphanumeric characters plus underscore and replace the reset with underscore.

halter73 · 2018-04-09T22:19:15Z

src/Microsoft.Extensions.Logging.Testing/Xunit/LoggedConditionalTheoryDiscoverer.cs

+            var skipReason = testMethod.EvaluateSkipConditions();
+            return skipReason != null
+               ? new[] { new SkippedTestCase(skipReason, DiagnosticMessageSink, discoveryOptions.MethodDisplayOrDefault(), testMethod) }
+               : base.CreateTestCasesForTheory(discoveryOptions, testMethod, theoryAttribute);


Does the base class not call EvaluateSkipConditions?

Not LoggedTheoryDiscoverer.

But isn't that what you're replacing? If this didn't need to call EvaluateSkipConditions before, why now?

No I'm replacing ConditionalTheoryDiscoverer. But this inherits from LoggedTheoryDiscoverer which doesn't call EvaluateSkipConditions.

Wouldn't ConditionalTheoryDiscoverer have it's own LoggedTheoryDiscoverer that does exactly this then? Why not use that?

I think I misunderstood. Could you derive from ConditionalTheoryDiscoverer?

Then I'll still need to override these two methods to create LoggedTestCase or LoggedTheoryTestCase. I don't see the benefit here.

halter73 · 2018-04-09T22:41:50Z

src/Microsoft.Extensions.Logging.Testing/Xunit/LoggedTestInvoker.cs

+                var classType = loggedTestClass.GetType();
+                var testOutputHelper = ConstructorArguments.Single(a => typeof(ITestOutputHelper).IsAssignableFrom(a.GetType())) as ITestOutputHelper;
+                var logLevelAttribute = TestMethod.GetCustomAttribute(typeof(LogLevelAttribute)) as LogLevelAttribute;
+                var testName = TestMethodArguments.Aggregate(TestMethod.Name, (a, b) => $"{a}_{(b ?? "null")}");


👍 for foldl

JunTaoLuo · 2018-04-10T01:45:45Z

src/Microsoft.Extensions.Logging.Testing/AssemblyTestLog.cs

        private static readonly int MaxPathLength = 245;
+        private static char[] InvalidFileChars = new char[]
+        {
+            '\"', '<', '>', '|', '\0',


Created a static blacklist by concatenating https://github.com/dotnet/coreclr/blob/f5ae6d14d9d49dbb9f4e97f605d2a5cceab04879/src/mscorlib/shared/System/IO/Path.Unix.cs#L13-L15 and https://github.com/dotnet/coreclr/blob/9ac41819ab05282798c498b373a5017b1c2c4e64/src/mscorlib/shared/System/IO/Path.Windows.cs#L12-L28
and added space and delete.

cc @halter73

JunTaoLuo · 2018-04-10T04:21:52Z

🆙📅

pakrym · 2018-04-10T15:43:34Z

Can we bring [assembly: Xunit.TestFramework("Microsoft.Extensions.Logging.Testing.LoggedTestFramework", "Microsoft.Extensions.Logging.Testing")] via MSBuild target?

pakrym · 2018-04-10T15:46:27Z

We can also add a method to LoggetTest to change

 [Fact]
        public void MyTest()
        {
            // using LoggerFactory
            using (var webhost = WebHost.CreateDefaultBuilder().ConfigureServices(collection => collection.AddSingleton(LoggerFactory)).Build())
            {
                //...
            }

to

[Fact]
        public void MyTest()
        {
            // using LoggerFactory
            using (var webhost = WebHost.CreateDefaultBuilder().ConfigureServices(AddTestLogging).Build())
            {
                //...
            }

Makes it a bit shorter and simpler.

pakrym · 2018-04-10T15:48:45Z

src/Microsoft.Extensions.Logging.Testing/AssemblyTestLog.cs

+
+            foreach (var c in s)
+            {
+                sb.Append(InvalidFileChars.Contains(c) ? Convert.ToByte(c).ToString("x") : $"{c}");


Now when we have space in the invalid character list, please, let's not use hex, a bunch of random lower case characters would make file names completely unreadable.

Agreed. I like keeping the invalid character list to a minimum, but I vote for replacing all the invalid characters with underscore.

Only append underscore if the previous character is not underscore. A_B is better than A_____B and might help long paths.

pakrym · 2018-04-10T16:12:25Z

src/Microsoft.Extensions.Logging.Testing/Xunit/LoggedTestInvoker.cs

+                // None resolved so create a new one and retain a reference to it for initialization/uninitialization
+                if (loggedTestClass.TestOutputHelper == null)
+                {
+                    loggedTestClass.TestOutputHelper = _output = new TestOutputHelper();


Don't you have to call
https://github.com/xunit/xunit/blob/bccfcccf26b2c63c90573fe1a17e6572882ef39c/src/xunit.execution/Sdk/Frameworks/Runners/XunitTestRunner.cs#L65
for TestOutputHelper to work?

https://github.com/aspnet/Logging/pull/798/files#diff-c858eb959e00fa40bcb7918ace88301fR37

pakrym · 2018-04-10T16:30:08Z

Couple of comments then LGTM, let's try to use it.

JunTaoLuo · 2018-04-10T19:32:48Z

Addressed the feedback items.

- Add filename handling for assembly test log

analogrelay · 2018-04-10T22:37:44Z

🎉

JunTaoLuo requested review from analogrelay and pakrym April 9, 2018 17:29

JunTaoLuo commented Apr 9, 2018

View reviewed changes

JunTaoLuo mentioned this pull request Apr 9, 2018

Make SkippedTestCase and related utilities public aspnet/Testing#301

Merged

pakrym reviewed Apr 9, 2018

View reviewed changes

analogrelay reviewed Apr 9, 2018

View reviewed changes

halter73 suggested changes Apr 9, 2018

View reviewed changes

JunTaoLuo commented Apr 10, 2018

View reviewed changes

pakrym reviewed Apr 10, 2018

View reviewed changes

JunTaoLuo force-pushed the johluo/logging-framework-discoverer branch from e86704c to 3e6b132 Compare April 10, 2018 19:32

JunTaoLuo force-pushed the johluo/logging-framework-discoverer branch 2 times, most recently from c9f2f08 to 1b8e402 Compare April 10, 2018 21:45

Implement file logging integration with xunit

81b11e8

- Add filename handling for assembly test log

JunTaoLuo force-pushed the johluo/logging-framework-discoverer branch from 1b8e402 to 81b11e8 Compare April 10, 2018 21:58

JunTaoLuo merged commit 81b11e8 into dev Apr 10, 2018

JunTaoLuo deleted the johluo/logging-framework-discoverer branch April 10, 2018 22:00

Implement file logging with default xunit tests #798

Implement file logging with default xunit tests #798

Uh oh!

Conversation

JunTaoLuo commented Apr 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

JunTaoLuo Apr 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pakrym Apr 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

JunTaoLuo commented Apr 9, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pakrym commented Apr 9, 2018

Uh oh!

analogrelay commented Apr 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

JunTaoLuo commented Apr 9, 2018 •

edited

Loading

JunTaoLuo Apr 9, 2018 •

edited

Loading

pakrym Apr 9, 2018 •

edited

Loading

analogrelay commented Apr 9, 2018 •

edited

Loading

JunTaoLuo Apr 9, 2018 •

edited

Loading

JunTaoLuo Apr 10, 2018 •

edited

Loading